CloudWatch Logs Insightsでログを調査する前に読む記事

今回はCloudWatch Logs Insightsの使い方について解説します。Lambdaのログを例にして調査するときに、CloudWatch Logs Insightsの構文をどう組み立てればログを抽出できるのか解説します。

#AWS

#CloudWatch Logs Insights

#CloudWatch Logs

#Amazon CloudWatch

佐藤智樹

2020.06.18

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

はじめに

CX事業本部@東京の佐藤智樹です。

今回はCloudWatch Logs Insightsの使い方について解説します。Lambdaのログを例にして調査するときに、CloudWatch Logs Insightsの構文をどう組み立てればログを抽出できるのかサンプルを用いて解説します。

CloudWatch Logs Insights自体はログを網羅的に検索できる強力な機能です。しかし、いきなり試すと抽出方法が良く分からないときがあったので記事にしました。サンプルのログと実際に抽出する際のクエリを表示するので、調査する際に役立つかと思います。記事の最後ではエラー対象の集計などユースケースにそったクエリも軽く紹介します。

本記事の対象読者は、Lambdaを使い始めた方やCloudWatch Logsをメインのログ監視に利用されている方です。サンプルのログはLambdaで提示しますので障害が起きた際にスムーズに問題の対象を発見できるようになるかと思います。今は問題が起きてなくても、将来起きた時に慌てずに対応できるようになるために読んで損はないと思います。（私は慌てたので…）本記事のサンプルを元に調査が捗れば幸いです。

CloudWatch Logs Insightsとは

以下公式からの引用です。

CloudWatch Logs Insights では、Amazon CloudWatch Logs のログデータをインタラクティブに検索して分析できます。クエリを実行することで、運用上の問題に効率的かつ効果的に対応できます。問題が発生した場合は、CloudWatch Logs Insights を使用して潜在的原因を特定し、デプロイした修正を検証できます。 CloudWatch Logs Insights には専用のクエリ言語といくつかのシンプルで強力なコマンドが含まれています。また、サンプルクエリ、コマンドの説明、クエリの自動補完、ログフィールドの検出を使用して CloudWatch Logs Insights を開始できます。サンプルクエリは、AWS のサービスの複数のログタイプ向けに用意されています。

CloudWatch Logs Insights を使用したログデータの分析

上記にあるように分析だけでなく問題の調査にも使えます。またS3に送ってAthenaで検索するような設計にしていなくても、CloudWatch Logsにログだけ出していれば調査が可能です。以下のようなクエリも最初からサンプルとして提供されているので、稼働させているLambdaや設定したVPCがあればすぐに試すことができます。サンプルを試す際は、CloudWatch Logs Insightsの画面を開いて右側のクエリから各サンプルを確認・実行することができます。

サンプルクエリのチュートリアルは以下に記載されています。

チュートリアル: サンプルクエリを実行および変更する - Amazon CloudWatch Logs

クエリの基本的な形式

クエリの基本的な構文は以下のリンクで紹介されています。

CloudWatch Logs Insights クエリ構文

7つのクエリコマンドがサポートされています。独断と偏見で説明しやすくするため公式とは紹介する順番を変更しています。

項目名	説明
display	表示する内容を設定
filter	クエリの結果を1つ以上の条件でフィルタリング
fields	指定したフィールドをログイベントから取得
sort	ログイベントをソート
stats	集約や統計計算、グループ化など
limit	出力するログイベントの件数を指定
parse	ログフイベントから正規表現で一時的な項目(エフェメラルフィールド)を作成できる

上記の基本的なクエリ以外にも、一般関数や文字列関数などが使用できます。今回の記事では、上記7クエリの紹介に絞ってサンプルコードを使用して実際にCloudWatch Logsからデータを抽出してみます。

事前準備

事前準備としてLambdaで何件かログを出力し、例として作成したログを抽出することで具体的な使用方法を確認します。 Lambdaは「関数の作成」から「log-test」という関数名を指定し、ランタイムは「Node.js 12.x」でアクセス権限は特に変更せず「関数の作成」ボタンでLambdaを作成してください。

次に作成画面から「テスト」を押下してテスト設定を表示させます。イベント名を適当に「testEvent」と設定し「作成」を押下します。

コードを以下のように修正します。以下のコードをベースにクエリを試していきます。ログ出力はJSON.stringifyを使用してJSON文字列化することでクエリのフィールドとして使用できます。詳細はfieldsクエリの節で紹介します。

exports.handler = async (event) => {
    console.log(JSON.stringify(event));
    const response = {
        statusCode: 200,
        body: JSON.stringify('Hello from Lambda!'),
    };
    return response;
};

コードの修正が完了したら「テスト」ボタンを適当に何回か押下してコードを実行しログを仕込んだら準備完了です。

各クエリの紹介と実例

本章では、先ほど紹介した7つのクエリを実例交えて紹介します。まず先ほどの関数が作成できた段階でCloudWatchの画面に移ってください。CloudWatchの画面の以下の部分にインサイトがあるので表示してください。

インサイトの画面で以下の画面のように先ほど作成した関数のロググループを指定してください。ログの検索範囲の時間は適宜変更してください。

displayクエリ

表示するフィールドを指定できます。単にログフィールド全体を確認する場合や特定のフィールドだけを表示したい場合に使用します。以下の例では実行時間と出力メッセージを全て表示します。（本番で使用する場合は後述するlimitなどで制限しない場合は1000件分ログレコードが出力されるので注意してください）

display @timestamp, @message

filterクエリ

クエリの結果を1つ以上の条件に基づいて条件に該当するログレコードのみを抽出します。条件式には比較演算子やブール演算子、部分文字列一致、正規表現が使用できます。調査などで特定のログメッセージが出ているログレコードを確認したい時は部分文字列一致が一番手軽に試せます。

部分文字列一致と正規表現は like か =~ で実行することができます。以下のクエリを実行するとINFOが含まれるログレコードだけが表示できます。INFOの部分を任意の文字列に変えると特定のメッセージでフィルタリングできます。

filter @message like /INFO/

以下の画面では2度Lambdaを実行したので2件分のログが出力されます。

fieldsクエリ

指定したフィールドをログイベントから取得できます。指定できるフィールドはログによって異なります。どんなフィールドが指定できるかは出力されたログから確認できます。displayクエリなどでログを出力した後、ログレコードの＋ボタンを押下してください。

ログでフィールドとして有効になっている項目が確認できます。今回の例では@messageやJSON形式で出力したkey1、key2、key3などがフィールドになっています。(ちなみにJSONはJSON文字列化していない場合は、フィールドとして指定できないのでログ出力を実装する場合は注意してください)

以下のクエリ実行するとkey情報だけを出力に持たせることができます。

filter @message like /INFO/
| fields key1

sortクエリ

ログレコードを順番に応じてソートできます。asc (昇順) と desc(降順)で並び順を指定できます。デフォルト設定ではasc (昇順)になります。次の例ではタイムスタンプに応じて降順にソートします。

filter @message like /INFO/
| fields @timestamp, key1
| sort @timestamp desc

statsクエリ

ログフィールドの値に基づいて関数で集約や統計計算が行えます。関数はavg()、sum()、count()、,min()、max()などがサポートされています。またstatsとbyを使うことでSQLのGroup byのように値を集約することもできます。

集約を試すためにLambdaのテストイベントを以下のように変更して何度か実行します。

{
  "key1": "good",
  "key2": "normal",
  "key3": "bad"
}

以下のクエリを実行するとkey1の項目内容ごとに何件実行されたのか確認できます。

filter @message like /INFO/
| stats count(key1) by key1

また非集約関数で最新のログの調査などもできます。以下の例はearliestを使用して、ログレコードの中で最もタイムスタンプが最新のレコードが表示されます。

filter @message like /INFO/
| stats earliest(@message)

また1点注意ですが以下のようにstatsで集約した後、再度statsで集約はできません。特定の項目で集約した後件数をカウントなどはできないです。

filter @message like /INFO/
| fields uuid
| stats count(*) by uuid
| stats count(*)

limitクエリ

limitを指定することで出力するログレコードの上限を指定できます。指定しない場合はデフォルトで1000件までログレコードが表示されます。以下の例ではログレコードをタイムスタンプ順で最新の3件のみ表示します。

filter @message like /INFO/
| fields @timestamp, key1
| sort @timestamp desc
| limit 3

parseクエリ

ログフィールドからデータを抽出して、1つ以上のエフェメラルフィールドを作成して文字列を抜き出すことができます。以下の例ではメッセージ内部でINFOの文字列を持つログフィールドからmessage内のINFO以降の部分だけを抽出しています。

（デフォルトのログ出力だとログレベル(INFOなど)とデータの間が空白でなくてタブになっているので、console.logや独自で作成したログを調査する場合は注意してください。動かなくて10分ぐらい悩みました）

filter @message like /INFO/
| parse @message "INFO\t*" as json

クエリの活用例

本章ではやりたいことに応じて構築したクエリを紹介します。実務の場合は前述したクエリを組み合わせて簡単な集計や障害対象の調査がメインだと思うので本章で紹介します。

ユニークユーザの数を知りたい

ユーザ固有のIDをログに出力していれば集約することでAPIを使用しているユニークユーザ数を確認できます。時間を区切ればとある期間でアクティブなユーザなどを確認することもできます。今回はLambdaがAPI Gatewayから実行されていると仮定して、テストイベントからLambdaを実行し確認します。

仮想の対象となるログを仕込むためLambdaのテストイベントを以下のように変更します。uuidは適当に何度か変更してテストを実行してください。

{
  "userId": "90d3d9e9-dcab-4b43-9a79-760faf0b7b00"
}

終わったらCloudWatch Logs Insightsを開いて以下のクエリでログが出力されていることを確認してください。

display @message

次に以下のクエリでAPIを実行したユニークユーザの件数が確認できます。

filter @message like /userId/
| fields userId
| stats count_distinct(userId)

上記のクエリでstatsの部分を「stats count(*) by userId」に変えれば、対象として上がったuserIdごとにAPIが何回実行されたかも分かります。

特定のエラーがでている対象のキー情報が知りたい

いくつかのユーザで特定のエラーが発生した状況を想定します。エラーが起きたユーザを特定するためのクエリを紹介します。

仮想のログを準備するためLambdaのソースとテストイベントを修正します。まずLambdaのコードを以下のように変更します。

exports.handler = async (event) => {
    console.error(JSON.stringify(event));
    const response = {
        statusCode: 200,
        body: JSON.stringify('Hello from Lambda!'),
    };
    return response;
};

次にLambdaのテストイベントを以下のように変更します。uuidの部分はどんな値でも良いので何回か変更して実行してください。

{
  "error": "UnknownError",
  "uuid": "9deae059-03bc-469f-861e-cbb1bff6b0f3"
}

終わったらCloudWatch Logs Insightsを開いて以下のクエリでログが出力されていることを確認してください。

display @message

次に以下のクエリでエラーとなった対象が何件いて何回ずつエラーが起きたのか確認できます。

filter error like /UnknownError/
| fields uuid
| stats count(uuid) as error_count by uuid

感想

CloudWatch Logs Insightsのクエリが最初よく分からなくて書いた記事ですが、fieldsクエリさえ理解すればlinuxのパイプとSQLの知識の流用で何とかなりそうでした。あまり複雑なことはできないので、より複雑な集計操作や分析を行いたい場合はS3にデータを流してAthenaで抽出する方が良いかと思います。

しかし、クエリ実行以外の追加費用無しでかつ、特別な設定も不要でログを網羅的に調査することが可能なのでかなり便利な機能だと思います。今後CloudWatch Logs Insightsを使われる方にとって、今回の記事が参考になれば幸いです。